Before https://reviews.llvm.org/D154984 and https://reviews.llvm.org/D156954, lit reported full RUN lines in a Script: section. Now, in the case of lit's internal shell, it's the execution trace that includes them. However, if lit is configured to use an external shell (e.g., bash, windows cmd), they aren't reported at all.

A fix was requested at the following:

• https://reviews.llvm.org/D154984#4627605
• https://discourse.llvm.org/t/rfc-improving-lits-debug-output/72839/35?u=jdenny-ornl

This patch does not address the case when the external shell is windows cmd. As discussed at #65242, it's not clear whether that's a use case that people still care about, and it seems to be generally broken anyway.

Patch is 134.19 KiB, truncated to 20.00 KiB below, full version: https://github.com/llvm/llvm-project/pull/66408.diff

42 Files Affected:

• (modified) libcxx/utils/libcxx/test/dsl.py (+1-1)
• (modified) libcxx/utils/libcxx/test/format.py (+3-46)
• (modified) llvm/docs/CommandGuide/lit.rst (+8-10)
• (modified) llvm/utils/lit/lit/LitConfig.py (-2)
• (modified) llvm/utils/lit/lit/TestRunner.py (+139-42)
• (modified) llvm/utils/lit/lit/cl_arguments.py (+6-8)
• (modified) llvm/utils/lit/lit/main.py (-1)
• (modified) llvm/utils/lit/tests/Inputs/lit-opts/lit.cfg (+1-1)
• (modified) llvm/utils/lit/tests/Inputs/shtest-define/examples/param-subst.txt (+4-4)
• (modified) llvm/utils/lit/tests/Inputs/shtest-define/expansion-order.txt (+4-4)
• (modified) llvm/utils/lit/tests/Inputs/shtest-define/line-number-substitutions.txt (+5-5)
• (modified) llvm/utils/lit/tests/Inputs/shtest-define/name-chars.txt (+6-6)
• (modified) llvm/utils/lit/tests/Inputs/shtest-define/recursiveExpansionLimit.txt (+2-2)
• (modified) llvm/utils/lit/tests/Inputs/shtest-define/value-equals.txt (+4-4)
• (modified) llvm/utils/lit/tests/Inputs/shtest-define/value-escaped.txt (+2-2)
• (modified) llvm/utils/lit/tests/Inputs/shtest-define/ws-and-continuations.txt (+17-17)
• (added) llvm/utils/lit/tests/Inputs/shtest-external-shell-kill/lit.cfg (+5)
• (added) llvm/utils/lit/tests/Inputs/shtest-external-shell-kill/test.txt (+5)
• (modified) llvm/utils/lit/tests/Inputs/shtest-if-else/test.txt (+40-24)
• (modified) llvm/utils/lit/tests/Inputs/shtest-output-printing/basic.txt (+2-1)
• (modified) llvm/utils/lit/tests/Inputs/shtest-output-printing/lit.cfg (+1)
• (added) llvm/utils/lit/tests/Inputs/shtest-output-printing/write-a-lot.py (+6)
• (added) llvm/utils/lit/tests/Inputs/shtest-run-at-line/external-shell/empty-run-line.txt (+3)
• (added) llvm/utils/lit/tests/Inputs/shtest-run-at-line/internal-shell/empty-run-line.txt (+3)
• (added) llvm/utils/lit/tests/Inputs/shtest-shell/echo-at-redirect-stderr.txt (+1)
• (added) llvm/utils/lit/tests/Inputs/shtest-shell/echo-at-redirect-stdin.txt (+2)
• (added) llvm/utils/lit/tests/Inputs/shtest-shell/echo-redirect-stderr.txt (+1)
• (added) llvm/utils/lit/tests/Inputs/shtest-shell/echo-redirect-stdin.txt (+2)
• (modified) llvm/utils/lit/tests/allow-retries.py (+24-5)
• (modified) llvm/utils/lit/tests/lit-opts.py (+2-2)
• (modified) llvm/utils/lit/tests/shtest-define.py (+8-8)
• (modified) llvm/utils/lit/tests/shtest-env.py (+79-52)
• (added) llvm/utils/lit/tests/shtest-external-shell-kill.py (+36)
• (modified) llvm/utils/lit/tests/shtest-format.py (+43-29)
• (modified) llvm/utils/lit/tests/shtest-if-else.py (+2-1)
• (modified) llvm/utils/lit/tests/shtest-inject.py (+20-25)
• (modified) llvm/utils/lit/tests/shtest-not.py (+132-85)
• (modified) llvm/utils/lit/tests/shtest-output-printing.py (+39-25)
• (modified) llvm/utils/lit/tests/shtest-pushd-popd.py (+6-6)
• (modified) llvm/utils/lit/tests/shtest-recursive-substitution.py (+3-3)
• (modified) llvm/utils/lit/tests/shtest-run-at-line.py (+62-44)
• (modified) llvm/utils/lit/tests/shtest-shell.py (+453-403)

diff --git a/libcxx/utils/libcxx/test/dsl.py b/libcxx/utils/libcxx/test/dsl.py
index 847cebf5962f6aa..4c2217ec31428b2 100644
--- a/libcxx/utils/libcxx/test/dsl.py
+++ b/libcxx/utils/libcxx/test/dsl.py
@@ -180,7 +180,7 @@ def programOutput(config, program, args=None):
                 "Failed to run program, cmd:\n{}\nstderr is:\n{}".format(runcmd, err)
             )
 
-        return libcxx.test.format._parseLitOutput(out)
+        return out
 
 
 @_memoizeExpensiveOperation(
diff --git a/libcxx/utils/libcxx/test/format.py b/libcxx/utils/libcxx/test/format.py
index ddd88f25646eaa8..c7c0bad681ddc8b 100644
--- a/libcxx/utils/libcxx/test/format.py
+++ b/libcxx/utils/libcxx/test/format.py
@@ -35,39 +35,6 @@ def _checkBaseSubstitutions(substitutions):
     for s in ["%{cxx}", "%{compile_flags}", "%{link_flags}", "%{flags}", "%{exec}"]:
         assert s in substitutions, "Required substitution {} was not provided".format(s)
 
-def _parseLitOutput(fullOutput):
-    """
-    Parse output of a Lit ShTest to extract the actual output of the contained commands.
-
-    This takes output of the form
-
-        $ ":" "RUN: at line 11"
-        $ "echo" "OUTPUT1"
-        # command output:
-        OUTPUT1
-
-        $ ":" "RUN: at line 12"
-        $ "echo" "OUTPUT2"
-        # command output:
-        OUTPUT2
-
-    and returns a string containing
-
-        OUTPUT1
-        OUTPUT2
-
-    as-if the commands had been run directly. This is a workaround for the fact
-    that Lit doesn't let us execute ShTest and retrieve the raw output without
-    injecting additional Lit output around it.
-    """
-    parsed = ''
-    for output in re.split('[$]\s*":"\s*"RUN: at line \d+"', fullOutput):
-        if output: # skip blank lines
-            commandOutput = re.search("# command output:\n(.+)\n$", output, flags=re.DOTALL)
-            if commandOutput:
-                parsed += commandOutput.group(1)
-    return parsed
-
 def _executeScriptInternal(test, litConfig, commands):
     """
     Returns (stdout, stderr, exitCode, timeoutInfo, parsedCommands)
@@ -79,21 +46,12 @@ def _executeScriptInternal(test, litConfig, commands):
     _, tmpBase = _getTempPaths(test)
     execDir = os.path.dirname(test.getExecPath())
     res = lit.TestRunner.executeScriptInternal(
-        test, litConfig, tmpBase, parsedCommands, execDir
+        test, litConfig, tmpBase, parsedCommands, execDir, debug=False
     )
     if isinstance(res, lit.Test.Result):  # Handle failure to parse the Lit test
         res = ("", res.output, 127, None)
     (out, err, exitCode, timeoutInfo) = res
 
-    # TODO: As a temporary workaround until https://reviews.llvm.org/D81892 lands, manually
-    #       split any stderr output that is included in stdout. It shouldn't be there, but
-    #       the Lit internal shell conflates stderr and stdout.
-    conflatedErrorOutput = re.search("(# command stderr:.+$)", out, flags=re.DOTALL)
-    if conflatedErrorOutput:
-        conflatedErrorOutput = conflatedErrorOutput.group(0)
-        out = out[: -len(conflatedErrorOutput)]
-        err += conflatedErrorOutput
-
     return (out, err, exitCode, timeoutInfo, parsedCommands)
 
 
@@ -400,9 +358,8 @@ def _generateGenTest(self, testSuite, pathInSuite, litConfig, localConfig):
             raise RuntimeError(f"Error while trying to generate gen test\nstdout:\n{out}\n\nstderr:\n{err}")
 
         # Split the generated output into multiple files and generate one test for each file
-        parsed = _parseLitOutput(out)
-        for (subfile, content) in self._splitFile(parsed):
-            generatedFile = testSuite.getExecPath(pathInSuite + (subfile, ))
+        for subfile, content in self._splitFile(out):
+            generatedFile = testSuite.getExecPath(pathInSuite + (subfile,))
             os.makedirs(os.path.dirname(generatedFile), exist_ok=True)
             with open(generatedFile, 'w') as f:
                 f.write(content)
diff --git a/llvm/docs/CommandGuide/lit.rst b/llvm/docs/CommandGuide/lit.rst
index 28319660d69c7c8..5e2443cb612a48d 100644
--- a/llvm/docs/CommandGuide/lit.rst
+++ b/llvm/docs/CommandGuide/lit.rst
@@ -94,21 +94,19 @@ OUTPUT OPTIONS
  Show more information on test failures, for example the entire test output
  instead of just the test result.
 
+ Each command is printed before it is executed. This can be valuable for
+ debugging test failures, as the last printed command is the one that failed.
+ Moreover, :program:`lit` inserts ``'RUN: at line N'`` before each
+ command pipeline in the output to help you locate the source line of
+ the failed command.
+
 .. option:: -vv, --echo-all-commands
 
- On test failure, echo all commands to stdout as they are being executed.
- This can be valuable for debugging test failures, as the last echoed command
- will be the one which has failed.
- :program:`lit` normally inserts a no-op command (``:`` in the case of bash)
- with argument ``'RUN: at line N'`` before each command pipeline, and this
- option also causes those no-op commands to be echoed to stdout to help you
- locate the source line of the failed command.
- This option implies ``--verbose``.
+ Deprecated alias for -v.
 
 .. option:: -a, --show-all
 
- Show more information about all tests, for example the entire test
- commandline and output.
+ Enable -v, but for all tests not just failed tests.
 
 .. option:: --no-progress-bar
 
diff --git a/llvm/utils/lit/lit/LitConfig.py b/llvm/utils/lit/lit/LitConfig.py
index 331c21d7b9dfcf2..d7e79b60f385bd3 100644
--- a/llvm/utils/lit/lit/LitConfig.py
+++ b/llvm/utils/lit/lit/LitConfig.py
@@ -36,7 +36,6 @@ def __init__(
         config_prefix=None,
         maxIndividualTestTime=0,
         parallelism_groups={},
-        echo_all_commands=False,
         per_test_coverage=False,
     ):
         # The name of the test runner.
@@ -87,7 +86,6 @@ def __init__(
 
         self.maxIndividualTestTime = maxIndividualTestTime
         self.parallelism_groups = parallelism_groups
-        self.echo_all_commands = echo_all_commands
         self.per_test_coverage = per_test_coverage
 
     @property
diff --git a/llvm/utils/lit/lit/TestRunner.py b/llvm/utils/lit/lit/TestRunner.py
index b2c50f563696fe2..528694b07f03300 100644
--- a/llvm/utils/lit/lit/TestRunner.py
+++ b/llvm/utils/lit/lit/TestRunner.py
@@ -8,6 +8,7 @@
 import stat
 import pathlib
 import platform
+import shlex
 import shutil
 import tempfile
 import threading
@@ -348,12 +349,12 @@ def executeBuiltinExport(cmd, shenv):
 
 
 def executeBuiltinEcho(cmd, shenv):
-    """Interpret a redirected echo command"""
+    """Interpret a redirected echo or @echo command"""
     opened_files = []
     stdin, stdout, stderr = processRedirects(cmd, subprocess.PIPE, shenv, opened_files)
     if stdin != subprocess.PIPE or stderr != subprocess.PIPE:
         raise InternalShellError(
-            cmd, "stdin and stderr redirects not supported for echo"
+            cmd, f"stdin and stderr redirects not supported for {cmd.args[0]}"
         )
 
     # Some tests have un-redirected echo commands to help debug test failures.
@@ -700,6 +701,7 @@ def _executeShCmd(cmd, shenv, results, timeoutHelper):
         "cd": executeBuiltinCd,
         "export": executeBuiltinExport,
         "echo": executeBuiltinEcho,
+        "@echo": executeBuiltinEcho,
         "mkdir": executeBuiltinMkdir,
         "popd": executeBuiltinPopd,
         "pushd": executeBuiltinPushd,
@@ -927,7 +929,7 @@ def _executeShCmd(cmd, shenv, results, timeoutHelper):
         if res == -signal.SIGINT:
             raise KeyboardInterrupt
         if proc_not_counts[i] % 2:
-            res = not res
+            res = 1 if res == 0 else 0
         elif proc_not_counts[i] > 1:
             res = 1 if res != 0 else 0
 
@@ -990,19 +992,60 @@ def _executeShCmd(cmd, shenv, results, timeoutHelper):
     return exitCode
 
 
-def executeScriptInternal(test, litConfig, tmpBase, commands, cwd):
+def formatOutput(title, data, limit=None):
+    if not data.strip():
+        return ""
+    if not limit is None and len(data) > limit:
+        data = data[:limit] + "\n...\n"
+        msg = "data was truncated"
+    else:
+        msg = ""
+    ndashes = 30
+    # fmt: off
+    out =  f"# .---{title}{'-' * (ndashes - 4 - len(title))}\n"
+    out += f"# | " + "\n# | ".join(data.splitlines()) + "\n"
+    out += f"# `---{msg}{'-' * (ndashes - 4 - len(msg))}\n"
+    # fmt: on
+    return out
+
+
+# Normally returns out, err, exitCode, timeoutInfo.
+#
+# If debug is True (the normal lit behavior), err is empty, and out contains an
+# execution trace, including stdout and stderr shown per command executed.
+#
+# If debug is False (set by some custom lit test formats that call this
+# function), out contains only stdout from the script, err contains only stderr
+# from the script, and there is no execution trace.
+def executeScriptInternal(test, litConfig, tmpBase, commands, cwd, debug=True):
     cmds = []
     for i, ln in enumerate(commands):
+        # Within lit, we try to always add '%dbg(...)' to command lines in order
+        # to maximize debuggability.  However, custom lit test formats might not
+        # always add it, so add a generic debug message in that case.
         match = re.fullmatch(kPdbgRegex, ln)
         if match:
+            dbg = match.group(1)
             command = match.group(2)
-            ln = commands[i] = match.expand(": '\\1'; \\2" if command else ": '\\1'")
+        else:
+            dbg = "command line"
+            command = ln
+        if debug:
+            ln = f"@echo '# {dbg}' "
+            if command:
+                ln += f"&& @echo {shlex.quote(command.lstrip())} && {command}"
+            else:
+                ln += "has no command after substitutions"
+        else:
+            ln = command
         try:
             cmds.append(
                 ShUtil.ShParser(ln, litConfig.isWindows, test.config.pipefail).parse()
             )
         except:
-            return lit.Test.Result(Test.FAIL, "shell parser error on: %r" % ln)
+            return lit.Test.Result(
+                Test.FAIL, f"shell parser error on {dbg}: {command.lstrip()}\n"
+            )
 
     cmd = cmds[0]
     for c in cmds[1:]:
@@ -1022,8 +1065,42 @@ def executeScriptInternal(test, litConfig, tmpBase, commands, cwd):
 
     out = err = ""
     for i, result in enumerate(results):
-        # Write the command line run.
-        out += "$ %s\n" % (" ".join('"%s"' % s for s in result.command.args),)
+        if not debug:
+            out += result.stdout
+            err += result.stderr
+            continue
+
+        # The purpose of an "@echo" command is merely to add a debugging message
+        # directly to lit's output.  It is used internally by lit's internal
+        # shell and is not currently documented for use in lit tests.  However,
+        # if someone misuses it (e.g., both "echo" and "@echo" complain about
+        # stdin redirection), produce the normal execution trace to facilitate
+        # debugging.
+        if (
+            result.command.args[0] == "@echo"
+            and result.exitCode == 0
+            and not result.stderr
+            and not result.outputFiles
+            and not result.timeoutReached
+        ):
+            out += result.stdout
+            continue
+
+        # Write the command line that was run.  Properly quote it.  Leading
+        # "!" commands should not be quoted as that would indicate they are not
+        # the builtins.
+        out += "# executed command: "
+        nLeadingBangs = next(
+            (i for i, cmd in enumerate(result.command.args) if cmd != "!"),
+            len(result.command.args),
+        )
+        out += "! " * nLeadingBangs
+        out += " ".join(
+            shlex.quote(str(s))
+            for i, s in enumerate(result.command.args)
+            if i >= nLeadingBangs
+        )
+        out += "\n"
 
         # If nothing interesting happened, move on.
         if (
@@ -1038,22 +1115,14 @@ def executeScriptInternal(test, litConfig, tmpBase, commands, cwd):
 
         # Add the command output, if redirected.
         for (name, path, data) in result.outputFiles:
-            if data.strip():
-                out += "# redirected output from %r:\n" % (name,)
-                data = to_string(data.decode("utf-8", errors="replace"))
-                if len(data) > 1024:
-                    out += data[:1024] + "\n...\n"
-                    out += "note: data was truncated\n"
-                else:
-                    out += data
-                out += "\n"
-
+            data = to_string(data.decode("utf-8", errors="replace"))
+            out += formatOutput(f"redirected output from '{name}'", data, limit=1024)
         if result.stdout.strip():
-            out += "# command output:\n%s\n" % (result.stdout,)
+            out += formatOutput("command stdout", result.stdout)
         if result.stderr.strip():
-            out += "# command stderr:\n%s\n" % (result.stderr,)
+            out += formatOutput("command stderr", result.stderr)
         if not result.stdout.strip() and not result.stderr.strip():
-            out += "note: command had no output on stdout or stderr\n"
+            out += "# note: command had no output on stdout or stderr\n"
 
         # Show the error conditions:
         if result.exitCode != 0:
@@ -1063,9 +1132,9 @@ def executeScriptInternal(test, litConfig, tmpBase, commands, cwd):
                 codeStr = hex(int(result.exitCode & 0xFFFFFFFF)).rstrip("L")
             else:
                 codeStr = str(result.exitCode)
-            out += "error: command failed with exit status: %s\n" % (codeStr,)
+            out += "# error: command failed with exit status: %s\n" % (codeStr,)
         if litConfig.maxIndividualTestTime > 0 and result.timeoutReached:
-            out += "error: command reached timeout: %s\n" % (
+            out += "# error: command reached timeout: %s\n" % (
                 str(result.timeoutReached),
             )
 
@@ -1095,21 +1164,49 @@ def executeScript(test, litConfig, tmpBase, commands, cwd):
                 commands[i] = match.expand(
                     "echo '\\1' > nul && " if command else "echo '\\1' > nul"
                 )
-        if litConfig.echo_all_commands:
-            f.write("@echo on\n")
-        else:
-            f.write("@echo off\n")
+        f.write("@echo on\n")
         f.write("\n@if %ERRORLEVEL% NEQ 0 EXIT\n".join(commands))
     else:
         for i, ln in enumerate(commands):
             match = re.fullmatch(kPdbgRegex, ln)
             if match:
+                dbg = match.group(1)
                 command = match.group(2)
-                commands[i] = match.expand(": '\\1'; \\2" if command else ": '\\1'")
+                # Echo the debugging diagnostic to stderr.
+                #
+                # For that echo command, use 'set' commands to suppress the
+                # shell's execution trace, which would just add noise.  Suppress
+                # the shell's execution trace for the 'set' commands by
+                # redirecting their stderr to /dev/null.
+ ...